为什么无论级别如何都评估python中的日志记录语句？

Question

为什么不管级别如何，python 中的日志记录语句都会被评估？

例如，在这段代码中，我希望仅在使用“-d”调用脚本时才打印“我被执行”语句，但它总是被打印！这意味着日志记录语句可能会对在更高日志记录级别运行的代码产生意想不到的影响。

#!/usr/bin/env python3

#import time
import argparse
import logging

logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR)

def logme():
    #time.sleep(10)
    print('I was executed ☠')
    return 'loggging all the things...'

if __name__ == "__main__":
    parser = argparse.ArgumentParser()
    parser.add_argument("--debug", "-d",
                         action='store_true',
                         help="Debug mode (very verbose)",
                        )

    args = parser.parse_args()
    if args.debug:
        logging.getLogger().setLevel(logging.DEBUG)

print('hello')
logging.debug('{}'.format(logme()))
print('bye')

这是日志模块中的错误吗？

Answer 1

归结为如何评估语句。在

logging.debug('{}'.format(logme()))

首先计算参数，然后调用logger.debug。因此，我们评估'{}'.format(logme())，然后将结果传递给logging.debug。很有效

x = '{}'.format(logme())
logging.debug(x)

让我们测试一下：

def run_later(x):
    print("function call")

def effect():
    print("parameter evaluation")

run_later(effect())
>>> parameter evaluation
>>> function call

Answer 2

这是日志模块中的错误吗？

没有。首先，输出 不同（将您的代码复制到 test.py）：

PS C:\Users\Matt> python test.py
hello
I was executed.
bye

对比

PS C:\Users\Matt> python test.py -d
hello
I was executed.
==> test, <module> loggging all the things...
bye

其次，如果您在程序中的任何位置调用logme()，"I was executed" 将打印到您的屏幕上。这是因为logme() 包含语句print('I was executed ☠')。这种特殊行为与logging 模块无关。它会打印到屏幕上，因为您在调用logme 函数时这样做：

logging.debug('{}'.format(logme()))

但是，logging 与 printing 不同，这就是我们看到不同输出的原因。 "I was executed" 将在调用时始终打印，但请注意"==> test, <module> loggging all the things..." 仅在指定-d 标志时记录。碰巧您在调用时将日志配置设置为 print（即logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR）。您可以登录到文件，或做其他类似的事情。

在logging 模块中使用格式字符串：

此外，如果您想在记录器中使用格式字符串，您实际上可以使用“%”样式格式，但您不实际上想要提供格式字符串。相反，将您的格式作为参数提供。这样做是因为 除非在适当的级别调用记录器，否则不会发生格式替换。替换为格式字符串是一项相对昂贵的操作，尤其是如果（例如）您的一个调试语句处于循环中。我的意思示例（将您的 logging.debug 语句替换为以下语句）：

# logging.debug('{}'.format(logme()))    
logging.debug('Some %s format %s string', 'first', 'second')

那么我们有：

PS C:\Users\Matt> python test.py
hello
bye

和：

PS C:\Users\Matt> python test.py -d
hello
==> test, <module> some first format second string
bye

HTH。

Answer 3

在日志记录函数内部做出做某事的决定，这就是为什么至少必须输入 logging.debug 的原因。您的 logme 函数在此之前运行并评估，以便可以传入其结果，这就是您看到“我被执行了吗？”的原因。打印出来的。

Answer 4

其他答案告诉您为什么总是评估 logme()，但如果您真的想要，您可以通过确保仅在结果转换为字符串时才调用 logme 来避免它：

#!/usr/bin/env python3

#import time
import argparse
import logging

logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR)

class LazyStr:
    def __init__(self, fn, *args, **kw):
        self.fn = fn
        self.args = args
        self.kw = kw

    def __str__(self):
        return str(self.fn(*self.args, **self.kw))


def logme(n, foo):
    #time.sleep(10)
    print('I was executed, n=%d, foo=%s' % (n, foo))
    return 'loggging all the things...'

if __name__ == "__main__":
    parser = argparse.ArgumentParser()
    parser.add_argument("--debug", "-d",
                         action='store_true',
                         help="Debug mode (very verbose)",
                        )

    args = parser.parse_args()
    if args.debug:
        logging.getLogger().setLevel(logging.DEBUG)

print('hello')
logging.debug('%s', LazyStr(logme, 42, foo='bar'))
print('bye')

LazyStr 对象将始终被创建，但 logme() 函数仅在日志级别为 debug 时才被调用。我还向logme 添加了一些参数，以展示如何传递参数。

输出：

$ ./t.py
hello
bye
$ ./t.py --debug
hello
I was executed, n=42, foo=bar
==> t, <module> loggging all the things...
bye