Python装饰器常见的错误

发表于 更新于 分类于 ，

虽然Python的装饰器是一个强大且有用的功能，但如果使用不当，也并非无懈可击。在这个部分，我们将讨论在设计和实现高效装饰器时需要避免的一些常见问题。

被包装对象的数据信息丢失

在将装饰器应用到函数时最常见的问题之一就是，原始函数的一些属性或特性并未被保留下来，从而导致一些不易被追踪的不良副作用。

为了说明这一点，对比这两个装饰器，他们的任务是在函数即将运行时进行日志记录：

1
2
3
4
5
6
7
8
9
10
11
12
def trace(function):
    def wrapped(*args, **kwargs):
        logger.info("running %s", function.__qualname__)
        return function(*args, **kwargs)
    return wrapped

@trace
def fun(index: str):
    """Processing index."""
    logger.info("processing index %s", index)
    ...

在语法上是没有问题的，并且可以执行，但是这种用法会把函数fun的信息修改掉

1
2
3
4
5
6
7
8
9
>>> help(fun)
Help on function wrapped in module __main__:
wrapped(*args, **kwargs)

>>> fun.__qualname__
'trace.<locals>.wrapped'

>>> process_account.__annotations__
{}

如果我们将类似的装饰器应用到多个函数上，虽然这些函数本身的名称各不相同，但最终它们都会被称为 “wrapped”，这是一个严重的问题（例如，如果我们希望对函数进行日志记录或跟踪，这将使得调试更加困难）。

另一个问题是，如果我们在这些函数上添加了带有测试的文档字符串，它们会被装饰器的文档字符串所覆盖。因此，当我们使用doctest模块调用代码时，我们想要运行的带有测试的文档字符串将不会执行

对此问题的修复十分简单，只需要使用functools.wraps

1
2
3
4
5
6
7
8
9
10
11
12
13
14
from functools import wraps

def trace(function):
    @wraps(function)
    def wrapped(*args, **kwargs):
        logger.info("running %s", function.__qualname__)
        return function(*args, **kwargs)
    return wrapped

@trace
def fun(index: str):
    """Processing index."""
    logger.info("processing index %s", index)

这样上面的问题就得到了修复

1
2
3
4
5
6
7
8
9
10
11
>>> help(fun)
Help on function fun in module __main__:

fun(index: str)
    Processing index.

>>> fun.__qualname__
'fun'

>>> fun.__annotations__
{'index': <class 'str'>}

最佳实践

在创建装饰器时，应始终使用functools.wraps应用于被包装的函数，如上面正确代码所示

装饰器作用范围错误

引发这个问题的原因，是没有理解装饰器内函数的作用范围，导致一些意料之外的执行错误。

假设我们有一个装饰器，它的目标是在函数开始运行时进行日志记录，然后记录其运行时间：

在python文件decorator_scope.py中定义如下代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
import logging as logger
import time
from functools import wraps

logger.basicConfig(level=logger.INFO)

def traced_function_execution_time(fun):
    logger.info("function %s started", fun)
    start_time = time.time()
    @wraps(fun)
    def wrapped(*args, **kwargs):
        result = fun(*args, **kwargs)
        logger.info(
            "function %s took %.2fs to finish",
            fun,
            time.time() - start_time
        )
        return result
    return wrapped


@traced_function_execution_time
def test(delay=0):
    time.sleep(delay)

这时如果我们import这个文件会得到下面的结果

1
2
3
4
5
6
7
8
>>> import decorator_scope
INFO:root:function <function test at 0x7f98f9ec6320> started
>>> test.test()
INFO:root:function <function test at 0x7fd98806e320> took 2.17s to finish
>>> test.test()
INFO:root:function <function test at 0x7fd98806e320> took 4.86s to finish
>>> test.test()
INFO:root:function <function test at 0x7fd98806e320> took 6.18s to finish

在没有调用函数test的情况下，一部分装饰器的代码被执行了。而且装饰器中的start_time变成了全局变量，无法得到正确的函数执行时间。

修复这个问题依然很简单，只需要修改装饰器traced_function_execution_time

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
def traced_function_execution_time(fun):
    @wraps(fun)
    logger.info("function %s started", fun)
    start_time = time.time()
    def wrapped(*args, **kwargs):
        result = fun(*args, **kwargs)
        logger.info(
            "function %s took %.2fs to finish",
            fun,
            time.time() - start_time
        )
        return result
    return wrapped

@traced_function_execution_time
def test(delay=0):
    time.sleep(delay)

装饰器语法在python运行时始终都会被这样执行：

1
2
3
4
def test(delay=0):
    time.sleep(delay)

test=traced_function_execution_time(test)

所以在引入模块时，装饰器中负责接收函数的部分就会被执行，从而导致意想不到的bug。