Модуль logging. Как при логировании указывать всю цепочку вызовов функции

Question

Хочется написать декоратор, который указывает всю цепочку вызовов. Вот, опираясь на статьи 1 и 2, написал такое:

import logging
import logging.config


def log(func):
    """
    Логируем какая функция вызывается.
    """  
    def wrap_log(*args, **kwargs):
        global logger
        saved_logger = logger
        # name = func.__name__
        logger = logging.getLogger(f"{logger.name}.{func.__name__}")
        logger.info(f"Вызов с args={args}, kwargs={kwargs}")
        result = func(*args, **kwargs)
        logger.debug(f"Результат: {result}")
        logger = saved_logger
        return func
    
    return wrap_log


@log
def double_function(a):
    """
    Умножаем полученный параметр.
    """
    return a*2

    
@log
def add_himself(a):
    return a+a


 
if __name__ == "__main__":
    logging.config.fileConfig('logging.config')
    logger = logging.getLogger("Sheduler")
    value = double_function(2)
    add_himself(2)
    add_himself("a")
    double_function("a")

И в принципе оно работает, но смущают меня глобальные переменные. Наверняка есть более "Пайтон"-решение.
Файл logging.config такой:

[loggers]
keys=root,Sheduler
 
[handlers]
keys=timedRotatingFileHandler, consoleHandler
 
[formatters]
keys=myFormatter
 
[logger_root]
level=CRITICAL
handlers=consoleHandler
 
[logger_Sheduler]
level=DEBUG
handlers=timedRotatingFileHandler
qualname=Sheduler
 
[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=myFormatter
args=(sys.stdout,)
 
[handler_timedRotatingFileHandler]
class=handlers.TimedRotatingFileHandler
formatter=myFormatter
args=("sheduler.log",)
kwargs={"when":"W1"}
 
[formatter_myFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

Answer 1

Действительно, использование глобальной переменной не позволит повторно использовать этот код в многопоточном коде.

Нужно использовать локальные переменные потока (threadlocal) для хранения текущего контекста:

import threading

logger_name = threading.local()

def log(func):
    """
    Логируем какая функция вызывается.
    """  
    def wrap_log(*args, **kwargs):
        saved_logger_name = logger_name.value
        try:
            logger_name.value = f"{logger_name.value}.{func.__name__}"
            logger = logging.getLogger(logger_name.value)
            logger.info(f"Вызов с args={args}, kwargs={kwargs}")
            result = func(*args, **kwargs)
            logger.debug(f"Результат: {result}")
            return func
        finally:
            logger_name.value = saved_logger_name
        
    return wrap_log

...

if __name__ == "__main__":
    logging.config.fileConfig('logging.config')
    logger_name.value = "Sheduler"
    ...

И обратите внимание, что восстановление нужно делать в finally, чтобы оно выполнилось даже если вызываемая функция бросит исключение.

Answer 2

Такая функция log уже реализована в библиотеке Polog (документация там на русском). Установим библиотеку:

$ pip install polog

И попробуем применить:

from polog import log, config, file_writer

config.add_handlers(file_writer())

@log
def function(a, b):
    return a / b

function(1, 2)

В результате в консоль запишется информация о вызове функции:

[2022-10-31 23:29:43.585581] |    1    | SUCCESS |  AUTO  | where: __main__.function() | time of work: 0.00001597 sec. | input variables: 1 (int), 2 (int) | result: 0.5 (float)

БЛОГ НА HUSL

Модуль logging. Как при логировании указывать всю цепочку вызовов функции

Ответы (2 шт):