How can I format a python logger which is defined in one class but calls itself from another class?

Question

I have an internal logging library which I consume to run my service. The library provides 2 logging capabilities, one for standard and one for debug. I want to log the filename and function name for the logger as well. Since the library does not provide that functionality, I modified the formatter. But I noticed that it is not working as expected. Please see below my expected output.

Here is the MWE

one.py

import logging
from logging import handlers
import datetime as dt
import time

class myFormatter(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")
            z = time.strftime("%z")
            s = "%s.%03d %s" % (t, record.msecs, z)
        return s

class Logger:
    @staticmethod
    def get(name):
        logger = logging.getLogger("example")
        handler = handlers.RotatingFileHandler("example.log", mode='a', maxBytes=10485760)

        formatter = myFormatter('%(asctime)s %(levelname)s: %(message)s')
        handler.setLevel(logging.DEBUG)
        handler.setFormatter(formatter)

        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)

        return logger

two.py

from one import Logger
from three import DebugLog

class Component(object):
    def __init__(self, name):
        self.name = name
        logname = name

        logger = Logger.get(logname)
        self.logger = logger

        self.debug = DebugLog(self)

three.py

class DebugLog:
    def __init__(self,component):
        self._component = component

    def _debug(self, msg, *args, **kwargs):
        self._component.logger.debug(msg, *args, **kwargs)

    def debug(self, msg, *args, **kwargs):
        self._debug(msg, *args, **kwargs)

main.py

from two import Component
from one import myFormatter

component = Component('myexample')

# this is my modification
DEBUG_LOG_FORMAT = myFormatter('%(asctime)s %(levelname)s: [%(filename)s:%(lineno)s - %(funcName)20s() ] %(message)s')

component.debug._component.logger.handlers[0].formatter = DEBUG_LOG_FORMAT

def component_log():
    component.logger.info("I log this in component log")

def component_debug_log():
    component.debug.debug("I log this in component debug log")

component_log()
component_debug_log()

Current output

➜  M-WR4R2NYKL6 ~/logging-bug python main.py
➜  M-WR4R2NYKL6 ~/logging-bug cat example.log
2023-11-03 10:45:16.450 +0530 INFO: [main.py:14 -        component_log() ] I log this in component log
2023-11-03 10:45:16.450 +0530 DEBUG: [three.py:8 -               _debug() ] I log this in component debug log

Expected output

2023-11-03 10:45:16.450 +0530 INFO: [main.py:14 -        component_log() ] I log this in component log
2023-11-03 10:45:16.450 +0530 DEBUG: [main.py:17 -  component_debug_log() ] I log this in component debug log

I can control only main.py and not the other files because I do not own them. I can maybe modify them by inheriting or monkey patching them but cannot change them at source.

Answer 1

can control only main.py and not the other files because I do not own them.

What about extending DebugLog to override debug()? That way you can use inspect module to get the caller's context and use it:

import inspect
from two import Component, DebugLog
from one import myFormatter

class MyDebugLog(DebugLog):
    def debug(self, msg, *args, **kwargs):
        caller_frame = inspect.currentframe().f_back
        # Update lambda to accept two arguments: stack_info and stacklevel
        self._component.logger.findCaller = lambda stack_info=None, stacklevel=None: (caller_frame.f_code.co_filename, caller_frame.f_lineno, caller_frame.f_code.co_name, None)
        super().debug(msg, *args, **kwargs)
        self._component.logger.findCaller = logging.getLoggerClass().findCaller


component = Component('myexample')

# Use our logger instead
component.debug = MyDebugLog(component)

DEBUG_LOG_FORMAT = myFormatter('%(asctime)s %(levelname)s: [%(filename)s:%(lineno)s - %(funcName)20s() ] %(message)s')
component.debug._component.logger.handlers[0].formatter = DEBUG_LOG_FORMAT

def component_log():
    component.logger.info("I log this in component log")

def component_debug_log():
    component.debug.debug("I log this in component debug log")

component_log()
component_debug_log()