pythonpython-3.xpython-loggingpython-object

How to move ContextFilter class for logging to separate module?


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?


Solution

  • 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