pythonloggingpython-logging

How can I subclass logging.Logger without breaking %(filename) in logging.Formatter's interpolation syntax


I am trying to write a custom logging.Logger subclass which is mostly working, but I run into issues when trying to use a logging.Formatter that includes the interpolated value %(filename) in the custom format, it prints the filename where my custom subclass is, rather than the filename of the code that called the logging function.

I've found a number of tutorials for subclassing Logger but none of them address the effects this has on the filename interpolation. Is there a straightforward solution to this without having to override large sections of logging.Logger?

Sample code defining my custom logger:

#-------------------------------------
# custom_logger.py
#-------------------------------------
import logging
import io
class CustomLogger(logging.Logger):
    
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.setLevel(logging.DEBUG)
        
        # create the record format
        formatter = logging.Formatter(fmt = "%(filename)s - %(message)s")
        
        # create the handler
        self.stream = io.StringIO()
        handler = logging.StreamHandler(self.stream)
        handler.setFormatter(formatter)
        self.addHandler(handler)
    
    def debug(self, msg, *args, **kwargs):
        super().debug(msg, *args, **kwargs)
        
        # do some other stuff
        ...        
#-------------------------------------
# test.py
#-------------------------------------
from custom_logger import CustomLogger
import logging

logging.setLoggerClass(CustomLogger)
myLog = logging.getLogger("myLog")
myLog.debug("hello world")
print(myLog.stream.getvalue())

Expected output: >>> test.py - hello world

Actual output: >>> custom_logger.py - hello world


Solution

  • This is already answered in https://stackoverflow.com/a/59492341/2138700

    The solution is to use the stacklevel keyword argument when calling the super().debug in your custom_logger code. Here is the relevant section from the documentation

    The third optional keyword argument is stacklevel, which defaults to 1. If greater than 1, the corresponding number of stack frames are skipped when computing the line number and function name set in the LogRecord created for the logging event. This can be used in logging helpers so that the function name, filename and line number recorded are not the information for the helper function/method, but rather its caller.

    So the modified code should be

    import logging
    import io
    class CustomLogger(logging.Logger):
        
        def __init__(self, *args, **kwargs):
            super().__init__(*args, **kwargs)
            self.setLevel(logging.DEBUG)
            
            # create the record format
            formatter = logging.Formatter(fmt = "%(filename)s - %(message)s")
            
            # create the handler
            self.stream = io.StringIO()
            handler = logging.StreamHandler(self.stream)
            handler.setFormatter(formatter)
            self.addHandler(handler)
        
        def debug(self, msg, *args, **kwargs):
            super().debug(msg, *args, stacklevel=2, **kwargs)
    

    Now the output will be test.py - hello world