I have ContextFilter Class in my python script which I am using to have a counter variable in log formatter. It works as expected and prints value of incremented variable in log.
But when I try to move this Class to a custom module that I have created it always prints the initial value of variable and not the incremented value. Obviously I am missing something.
Contents of module log_format.py:
import logging
import datetime as dt
# As I need date in 2022-02-22 16:42:44.289193 format
class Formatter(logging.Formatter):
converter=dt.datetime.fromtimestamp
def formatTime(self, record, datefmt=None):
ct = self.converter(record.created)
if datefmt:
s = ct.strftime(datefmt)
else:
t = ct.strftime("%Y-%m-%d %H:%M:%S")
s = "%s,%03d" % (t, record.msecs)
return s
#class ContextFilter(logging.Filter): # RUN 2
# def __init__(self, i): # RUN 2
# self.i = i # RUN 2
# # RUN 2
# def filter(self, record): # RUN 2
# record.log_count = self.i # RUN 2
# return True # RUN 2
Contents of python script log_format_test.py
import os
import sys
import logging
py_lib = os.environ.get('app_dir') + "/lib"
sys.path.append(py_lib)
import log_format as lf
class ContextFilter(logging.Filter): # RUN 1
def filter(self, record): # RUN 1
record.log_count = i # RUN 1
return True # RUN 1
logger = logging.getLogger(__name__)
l_level = 'INFO' #'DEBUG' #'INFO'
l_level = eval("logging." + l_level.upper())
logger.setLevel(l_level)
int_var = os.getpid()
i = 0
str_var = os.path.basename(__file__)
handler = logging.StreamHandler()
handler.setLevel(l_level)
lf_format = f'ZZZZZZZZ|%(asctime)s|{int_var}|%(log_count)s|{str_var}|%(message)s'
formatter = lf.Formatter(fmt=lf_format, datefmt='%Y-%m-%d %H:%M:%S.%f') # 2022-02-22 16:42:44.289193
logger.addFilter(ContextFilter()) # RUN 1
#logger.addFilter(lf.ContextFilter(i)) # RUN 2
handler.setFormatter(formatter)
logger.addHandler(handler)
i += 1; logger.info("I am INFO 0")
i += 1; logger.info("I am INFO 1")
i += 1; logger.debug("I am DEBUG 0")
When I run script log_format_test.py
it does print log as expect with 4th field incremented for each log entry (RUN 1):
ZZZZZZZZ|2022-02-24 11:41:19.578733|20527|1|log_format_test.py|I am INFO 0
ZZZZZZZZ|2022-02-24 11:41:19.578868|20527|2|log_format_test.py|I am INFO 1
But when I try to move class ContextFilter
out of log_format_test.py
in to log_format.py
by uncommenting # RUN 2
lines and commenting # RUN 1
lines, the log shows only initial value in 4th field which is 0 (RUN 2):
ZZZZZZZZ|2022-02-24 11:55:24.679430|29115|0|log_format_test.py|I am INFO 0
ZZZZZZZZ|2022-02-24 11:55:24.679552|29115|0|log_format_test.py|I am INFO 1
Question: How can I move move class ContextFilter
out of log_format_test.py
in to log_format.py
(or a new module of it's own)? What am I missing here?
I was able to figure out how I could do this.
Contents of module log_format.py
import logging
import datetime as dt
class Formatter(logging.Formatter):
converter=dt.datetime.fromtimestamp
def formatTime(self, record, datefmt=None):
ct = self.converter(record.created)
if datefmt:
s = ct.strftime(datefmt)
else:
t = ct.strftime("%Y-%m-%d %H:%M:%S")
s = "%s,%03d" % (t, record.msecs)
return s
class ContextFilter(logging.Filter): # RUN 2
def __init__(self, i): # RUN 2
self.i = i # RUN 2
# RUN 2
def filter(self, record): # RUN 2
self.i += 1 # NEW LINE
record.log_count = self.i # RUN 2
return True # RUN 2
Contents of python script log_format_test.py
import os
import sys
import logging
py_lib = os.environ.get('app_dir') + "/lib"
sys.path.append(py_lib)
import log_format as lf
logger = logging.getLogger(__name__)
l_level = 'INFO' #'DEBUG' #'INFO'
l_level = eval("logging." + l_level.upper())
logger.setLevel(l_level)
int_var = os.getpid()
i = 0
str_var = os.path.basename(__file__)
handler = logging.StreamHandler()
handler.setLevel(l_level)
lf_format = f'ZZZZZZZZ|%(asctime)s|{int_var}|%(log_count)s|{str_var}|%(message)s'
formatter = lf.Formatter(fmt=lf_format, datefmt='%Y-%m-%d %H:%M:%S.%f') # 2022-02-22 16:42:44.289193
obj_filter = lf.ContextFilter(i) # NEW LINE
logger.addFilter(lf.ContextFilter(obj_filter)) # CHANGED LINE
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.info("I am INFO 1")
logger.info("I am INFO 2")
logger.debug("I am DEBUG 3")
This results in printing the log as expected and I don't even have to manually increment i every time.
ZZZZZZZZ|2022-02-24 11:41:19.578733|20527|1|log_format_test.py|I am INFO 1
ZZZZZZZZ|2022-02-24 11:41:19.578868|20527|2|log_format_test.py|I am INFO 2