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

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

值得注意的有两点：

1. 我们在实现自定义的__getattribute__方法的时候判断访问的对象的属性是方法而不是其他字段的时候做了两个判断，一个是当前属性是否可执行(callable(value) is True)，另一个是当前的属性名称不能以双下划线__开头，不然的话对象实例化调用__init__方法，打印日志的时候调用__str__或者__repr__方法的时候也会记录日志。
2. 这里我们没有使用上面的装饰器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 函数和方法调用日志的机制，这些机制在生产环境中使用并没有太大的问题，只需要配置一下日志的级别和格式（加上时间、运行时的文件和行号等）。

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