python - 如何让被调用的函数使用装饰器进行日志记录？

Question

我想将一些事件写入日志文件。为了做到这一点，我使用了函数装饰器来添加登录代码，并报告调用的函数。但是，输出始终是同一个函数，装饰器函数 _decorador。

我正在使用格式为 logging.basicConfig 的 %(funcName)s 参数

example.log 中的输出:

04/21/2014 09:32:41 AM DEBUG This message should go to the log file _decorador
04/21/2014 09:32:41 AM INFO So should this _decorador
04/21/2014 09:32:41 AM WARNING And this, too _decorador
04/21/2014 10:46:23 AM DEBUG This message should go to the log file (debug) _decorador
04/21/2014 10:46:23 AM INFO So should this (info) _decorador
04/21/2014 10:46:23 AM WARNING And this, too (warning) _decorador

example.log 中的期望输出:

04/21/2014 09:32:41 AM DEBUG This message should go to the log file mi_funcion
04/21/2014 09:32:41 AM INFO So should this mi_funcion
04/21/2014 09:32:41 AM WARNING And this, too mi_funcion
04/21/2014 10:46:23 AM DEBUG This message should go to the log file (debug) mi_funcion
04/21/2014 10:46:23 AM INFO So should this (info) mi_funcion
04/21/2014 10:46:23 AM WARNING And this, too (warning) mi_funcion

我的代码:

#!usr/bin/python3
# -*- coding: UTF-8 -*-

import logging

FORMAT = '%(asctime)s %(levelname)s %(message)s %(funcName)s'
logging.basicConfig(filename='example.log', level=logging.DEBUG, format=FORMAT, datefmt='%m/%d/%Y %I:%M:%S %p')

# Decorator function, writes in the log file.
def decorador(funcion):
    def _decorador(*args, **kwargs):
        funcion(*args, **kwargs)
        logging.debug('This message should go to the log file (debug)')
        logging.info('So should this (info)')
        logging.warning('And this, too (warning)')
    return _decorador

    @decorador
def mi_funcion(arg1, arg2):
    print("Code asset: %s; Registry number: s%" % (arg1, arg2))

mi_funcion("18560K", 12405)

Answer 1

现在是 2022 年，这仍然很困难。

这是一个改编自 Using functools.wraps with a logging decorator 的完整示例

from inspect import getframeinfo, stack
import logging
from functools import wraps

class CustomFormatter(logging.Formatter):
    """Custom formatter, overrides funcName with value of name_override if it exists"""
    def format(self, record):
        if hasattr(record, 'name_override'):
            record.funcName = record.name_override
        if hasattr(record, 'file_override'):
            record.filename = record.file_override
        if hasattr(record, 'line_override'):
            record.lineno= record.line_override
        return super(CustomFormatter, self).format(record)

# setup logger and handler
logger = logging.getLogger(__file__)
handler = logging.StreamHandler()
logger.setLevel(logging.DEBUG)
handler.setLevel(logging.DEBUG)
handler.setFormatter(CustomFormatter('%(asctime)s - %(filename)s:%(lineno)s - %(funcName)s - %(levelname)s - %(message)s'))
logger.addHandler(handler)

def log_and_call(statement):
    def decorator(func):
        caller = getframeinfo(stack()[1][0])
        @wraps(func)
        def wrapper(*args, **kwargs):
            # set name_override to func.__name__
            logger.info(statement, extra={
                'name_override': func.__name__,
                'file_override': os.path.basename(caller.filename),
                'line_override': caller.lineno
                })
            return func(*args, **kwargs)
        return wrapper
    return decorator

@log_and_call("This should be logged by 'decorated_function'")
def decorated_function():  # <- the logging in the wrapped function will point to/log this line for lineno.
    logger.info('I ran')

decorated_function()

在 wrapper 函数之外定义调用者将正确获取调用函数(即包装函数)的文件名和行号。