为什么禁止覆盖日志记录属性？答案

【问题标题】：Why is it forbidden to override log record attributes?为什么禁止覆盖日志记录属性？
【发布时间】：2017-04-13 05:33:07
【问题描述】：

阅读 Python 的 logging 库的文档（适用于 2.7 版）我遇到了以下问题：

Logger.debug(msg, *args, **kwargs)

[...] 第二个关键字参数是额外的，可用于传递一个字典，该字典用于填充为具有用户定义属性的日志事件创建的 LogRecord 的__dict__。然后可以随意使用这些自定义属性。例如，它们可以合并到记录的消息中。 [...] 额外传入的字典中的键不应与日志系统使用的键发生冲突。 [emph.我的]

那么为什么会存在这个约束呢？在我看来，这无缘无故地从库中删除了灵活性（由开发人员检查哪些键是内置的，哪些不是）。

假设你想写一个装饰器来记录函数的进入和退出：

def log_entry_exit(func):
    def wrapper(*args, **kwargs):
        logger.debug('Entry')
        result = func(*args, **kwargs)
        logger.debug('Exit')
        return result
    return wrapper

@log_entry_exit
def foo():
    pass

假设您还想记录封闭函数的名称：

format_string = '%(funcName)s: %(message)s'

哎呀！这行不通。输出是：

>>> foo()
wrapper: Entry
wrapper: Exit

当然，函数名的计算结果为wrapper，因为那是封闭函数。然而，这不是我想要的。我想要打印装饰函数的函数名。因此，将我的日志调用修改为：

logger.debug('<msg>', extra={'funcName': func.__name__})

但是（正如文档已经指出的那样）这不起作用：

KeyError: "Attempt to overwrite 'funcName' in LogRecord"

尽管如此，对于给定问题，这将是一个非常简单明了的解决方案。

那么，为什么logging 阻止我为内置属性设置自定义值？

【问题讨论】：

我不确定这是否真的可以回答。该模块按照文档中的描述工作。至于为什么模块是这样设计的，你得问问开发者。

标签： python logging

【解决方案1】：

不是作者，我不能肯定，但我有一种预感。

看着 https://hg.python.org/cpython/file/3.5/Lib/logging/init.py，这似乎是引发您引用的错误的代码：

rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func, sinfo)
if extra is not None:
    for key in extra:
        if (key in ["message", "asctime"]) or (key in rv.__dict__):
            raise KeyError("Attempt to overwrite %r in LogRecord" % key)
        rv.__dict__[key] = extra[key]

查看该文件中的 _ _ init _ _() 方法，我们可以看到它设置了一长串属性，其中至少有一些用于跟踪对象状态（借用其他地方的术语，这些服务于私有成员变量的目的）：

self.args = args
self.levelname = getLevelName(level)
self.levelno = level
self.pathname = pathname
try:
    self.filename = os.path.basename(pathname)
    self.module = os.path.splitext(self.filename)[0]
except (TypeError, ValueError, AttributeError):
    self.filename = pathname
    self.module = "Unknown module"
self.exc_info = exc_info
self.exc_text = None      # used to cache the traceback text
self.stack_info = sinfo
self.lineno = lineno
self.funcName = func
[...]

代码在各个地方都假设这些属性包含它们被初始化的内容；正如我们在上面看到的那样，它不会在每次使用该值时都防御性地检查该值是否仍然合理，而是阻止尝试更新它们中的任何一个。而且，它不是试图区分“可安全覆盖”和“不可安全覆盖”属性，而是简单地阻止任何覆盖。

在 funcName 的特殊情况下，我怀疑你不会因为覆盖它而遭受任何不良影响（除了显示不同的 funcName）。

可能的前进方向：

活在局限中
覆盖 Logger.makeRecord() 以允许更新 funcName
覆盖 Logger 以添加 setFuncName() 方法

当然，无论你做什么，都要仔细测试你的修改以避免意外。

【讨论】：

【解决方案2】：

我知道这是几年前的事，但没有选择的答案。如果其他人遇到它，我有一个解决方法应该在日志模块发生更改时继续工作。

不幸的是，作者没有以易于检查的方式公开可能发生冲突的键。但是，他/她确实在文档中暗示了这样做的方法。此行：https://hg.python.org/cpython/file/3.5/Lib/logging/init.py#l368 返回 LogRecord 对象的外壳：

rv = _logRecordFactory(None, None, "", 0, "", (), None, None)

...在这个对象中你可以看到所有的属性，你可以创建一个Set 来保存“冲突键”。

我创建了一个日志辅助模块：

import logging

clashing_keywords = {key for key in dir(logging.LogRecord(None, None, "", 0, "", (), None, None)) if "__" not in key}
additional_clashing_keywords = {
    "message", 
    "asctime"
}
clashing_keywords = clashing_keywords.union(additional_clashing_keywords)

def make_safe_kwargs(kwargs):
    '''
    Makes sure you don't have kwargs that might conflict with
    the logging module
    '''
    assert isinstance(kwargs, dict)
    for k in kwargs:
        if k in clashing_keywords:
            kwargs['_'+k] = kwargs.pop(k)

    return kwargs

...它只是在冲突的键前面加上_。可以这样使用：

from mymodule.logging_helpers import make_safe_kwargs

logger.info("my message", extra=make_safe_kwargs(kwargs))

它一直对我很好。希望这会有所帮助！

【讨论】：

【解决方案3】：

对我来说，简短的回答是识别名称冲突，并重命名 kwarg：

#broken
log.info('some message', name=name)

# working
log.info('some message', special_name=name)

【讨论】：