使用装饰器、魔法方法和元类机制自动记录 Python 函数和方法调用日志

追不上乌龟的兔子 2021-08-09

695

在软件开发中，日志记录一直是一件让程序员很矛盾的事情。在编写代码的时候，不能确定需要将哪些信息记录日志；真正出了问题或者想统计分析一些用户行为和系统状态的时候，又发现没有充足的日志。
一个不错的解决方案是利用自动化机制记录关键函数和方法的调用记录。今天我们来看几种自动记录 Python 函数和方法调用日志的实现手段。

手动记录日志

这是最标准和常见的方法，在需要的时候手动记录一些信息，优点是完全可控，缺点是容易缺失一些真正重要的信息的记录。

import logging
logger = logging.getLogger(__name__)


def func(*args, **kwargs):
    logger.info(f'Call func with {args, kwargs}')


func(1, 2, 3, a=True, b='arg')

INFO:__main__:Call func with ((1, 2, 3), {'a': True, 'b': 'arg'})

使用装饰器记录函数和方法调用日志

我们可以利用 Python 的装饰器记录函数和方法调用的参数和返回值。

def func_logger(func):
    def inner(*args, **kwargs):
        ret = func(*args, **kwargs)
        logger.info(f'Call func {func.__name__} with {args, kwargs} returns {ret}')
        return ret


    return inner


@func_logger
def add(a, b):
    return a + b


add(1,2)
add(1, b=2)
add(a=1, b=2)

INFO:__main__:Call func add with ((1, 2), {}) returns 3
INFO:__main__:Call func add with ((1,), {'b': 2}) returns 3
INFO:__main__:Call func add with ((), {'a': 1, 'b': 2}) returns 3

对于装饰方法调用的场景，因为 Python 类方法的第一个参数是 self，需要做一下处理。

def method_logger(method):


    def inner(self, *args, **kwargs):
        ret = method(self, *args, **kwargs)
        logger.info(f'Call method {method.__name__} of {self} with {args, kwargs} returns {ret}')
        return ret


    return inner




class A:
    a:int
    def __init__(self, a):
        self.a = a


    @method_logger
    def addX(self, x: int):
        return self.a + x


    def __repr__(self):
        return f'A(a={self.a})'




a = A(1)
a.addX(2)
a.addX(x=3)

INFO:__main__:Call method addX of A(a=1) with ((2,), {}) returns 3
INFO:__main__:Call method addX of A(a=1) with ((), {'x': 3}) returns 4

值得注意的是使用了method_logger
装饰器的类最好有定义好__repr__
方法或者__str__
方法，这样可以在日志中直接获取到当前对象的状态。
配合dataclass
使用的话可以省掉自定义模仿方法的操作。

from dataclasses import dataclass


@dataclass
class Account:
    uid: str
    banlance: int


    @method_logger
    def transerTo(self, target: 'Account', value:int):
        self.banlance -= value
        target.banlance += value
        return self, target


a = Account('aaaa', 10)
b = Account('bbbb', 10)
a.transerTo(b, 5)

INFO:__main__:Call method transerTo of Account(uid='aaaa', banlance=5) with ((Account(uid='bbbb', banlance=15), 5), {}) returns (Account(uid='aaaa', banlance=5), Account(uid='bbbb', banlance=15))

使用`getattrbiture`
魔法方法记录方法调用日志

使用上述装饰器可以很好的记录我们需要关注的函数和方法的调用日志，但存在一个小问题是如果我们想自动记录一个类的所有方法调用的话，就需要为每一个自定义方法上加上method_logger
装饰器，稍微有一点繁琐。解决这个问题也很简单，只需要重写类的__getattribute__
方法。

def method_logger_x(method, obj):
    def inner(*args, **kwargs):
        ret = method(*args, **kwargs)
        logger.info(f'Call method {method.__name__} of {obj} with {args, kwargs} returns {ret}')
        return ret
    return inner




class MethodLogger:
    def __getattribute__(self, key):
        value = super().__getattribute__(key)
        if callable(value) and not key.startswith('__'):
            return method_logger_x(value, self)
        return value


@dataclass
class Account(MethodLogger):
    uid: str
    banlance: int
    frozen: bool = False


    def transerTo(self, target: 'Account', value:int):
        self.banlance -= value
        target.banlance += value
        return self, target


    def freeze(self, reason:str):
        self.frozen = True


a = Account('aaaa', 10)
b = Account('bbbb', 10)
a.transerTo(b, 5)
a.freeze('Dangerous Action')

INFO:__main__:Call method transerTo of Account(uid='aaaa', banlance=5, frozen=False) with ((Account(uid='bbbb', banlance=15, frozen=False), 5), {}) returns (Account(uid='aaaa', banlance=5, frozen=False), Account(uid='bbbb', banlance=15, frozen=False))
INFO:__main__:Call method freeze of Account(uid='aaaa', banlance=5, frozen=True) with (('Dangerous Action',), {}) returns None

值得注意的有两点：

我们在实现自定义的__getattribute__
方法的时候判断访问的对象的属性是方法而不是其他字段的时候做了两个判断，一个是当前属性是否可执行(callable(value) is True
)，另一个是当前的属性名称不能以双下划线__
开头，不然的话对象实例化调用__init__
方法，打印日志的时候调用__str__
或者__repr__
方法的时候也会记录日志。
这里我们没有使用上面的装饰器mehtod_logger
,而是重新编写一个装饰器函数method_logger_x
。原因是两个装饰器装饰的方法实际上有所区别：
method_logger
装饰的方法是在定义类的时候定义的方法，此时self
被认为是一个普通的参数，在装饰器内部调用被装饰方法的时候也要把self
传进去。
而通过__getattribute__
获取到的方法对象本身就是已经实例化好的对象的方法，已经隐含了self
在参数列表中。
method_logger_x
需要额外传obj
进去则是为了在记录日志的时候获取到当前方法的宿主对象。

使用元类自动记录方法调用日志

上述两种手段，使用method
装饰器在类定义好的时候就已经对需要装饰的方法进行了处理，使用__attrbiture__
魔法方法记录方法调用日志则是在每次调用当前对象的方法时对方法进行了特殊处理，会稍微增加一些运行时开销（对于 Python 解释器并没有什么显著区别）。我们还有另一种方法可以在类定义好的时候就对所有方法增加自动记录调用日志的处理，那就是使用元类机制。

Python 中的元类

这里简单介绍一下 Python 的元类，Python 的所有自定类都是在运行时由解释器通过type
函数现场生成的，函数签名type(name, bases, dict)
中的name
是类的名称，bases
是父类列表（tuple 类型），dict
是类的所有自定义方法和属性的字典。
我们可以用type
函数简单的定义一个类出来。

def A_init(self, a:int):
    self.a = a
A = type('A',(object,),dict(__init__=A_init, __str__= lambda self: f'A(a={self.a})'))


a = A(1)
print(a)
# A(a=1)

如果我们定义一个类Meta
继承type
,并且重写__new__
方法，我们就定义了一个元类。

from typing import Tuple
from  datetime import datetime
class Meta(type):
    def __new__(self, name:str, bases:Tuple[type], attrs:dict):
        attrs['time_defined'] = datetime.now()
        return type(name, bases, attrs)


class A(metaclass=Meta):
    pass


A.time_defined
# datetime.datetime(2020, 9, 6, 14, 14, 7, 938370)

可以看到，一个指定了Meta
为元类的类会自动添加一个属性time_defined
, 得到类在 Python 解释器的实际定义时间。

总结一下，元类就是通过继承type
类型重写__new__
方法在指定了元类的类定义的时候改变其行为的一种机制。

使用元类自动记录方法调用日志

下面我们用元类机制实现自动记录类方法调用日志的机制。

def method_logger(method):
    def inner(self, *args, **kwargs):
        ret = method(self, *args, **kwargs)
        logger.info(f'Call method {method.__name__} of {self} with {args, kwargs} returns {ret}')
        return ret


    return inner


from typing import Tuple
class MethodLoggerMeta(type):
    def __new__(self, name:str, bases:Tuple[type], attrs:dict):
        attrs_copy = attrs.copy()
        for key, value in attrs.items():
            if callable(value) and not key.startswith('__'):
                attrs_copy[key] = method_logger(value)
        return type(name, bases, attrs_copy)


@dataclass
class Account(metaclass=MethodLoggerMeta):
    uid: str
    banlance: int
    frozen: bool = False


    def transerTo(self, target: 'Account', value:int):
        self.banlance -= value
        target.banlance += value
        return self, target


    def freeze(self, reason:str):
        self.frozen = True


a = Account('aaaa', 10)
b = Account('bbbb', 10)
a.transerTo(b, 5)

这里我们使用的装饰器是显式指定self
参数的method_logger
版本，原因和上述说明一致，在定义的时候类的方法就是普通的函数，没有隐式的 self 对象。

总结

本文介绍了一些自动记录 Python 函数和方法调用日志的机制，这些机制在生产环境中使用并没有太大的问题，只需要配置一下日志的级别和格式（加上时间、运行时的文件和行号等）。

真实生产环境中，对于复杂函数和方法的执行，只有调用日志可能还不够，需要手动记录一些关键行为。当然只要把复杂的函数和方法拆分的足够细致，子函数和子方法的调用日志就可以补充足够的细节了。

python

文章转载自追不上乌龟的兔子，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

使用装饰器、魔法方法和元类机制自动记录 Python 函数和方法调用日志

手动记录日志

使用__getattrbiture__魔法方法记录方法调用日志

使用元类自动记录方法调用日志

Python 中的元类

使用元类自动记录方法调用日志

总结

评论

使用`getattrbiture`
魔法方法记录方法调用日志