Python 日志记录指南

对于开发人员来说，最糟糕的事情莫过于试图找出应用程序无法正常工作的原因，如果你不知道应用程序内部发生了什么。有时你甚至无法判断系统是否按设计运行。

当应用程序在生产环境中运行时，它们会变成需要跟踪和监控的黑盒。最简单但最重要的方法之一就是日志记录。日志记录使我们能够在开发软件时指示程序在系统运行时发出信息，这些信息对我们和我们的系统管理员都很有用。

正如我们为未来的开发人员编写代码文档一样，我们也应该指导新的软件生成足够的日志，供开发人员和系统管理员使用。日志是关于应用程序运行时状态的系统文档的关键部分。当使用日志记录来检测您的软件时，请将其视为为将来维护系统的开发人员和系统管理员编写文档。

一些纯粹主义者认为，使用日志记录和测试的严谨开发人员几乎不需要交互式调试器。如果我们在开发过程中无法通过详细的日志记录来推断我们的应用程序，那么当我们的代码在生产环境中运行时，就更难做到这一点了。

本文着眼于 Python 的 logging 模块、其设计以及使其适应更复杂用例的方法。本文并非旨在作为开发人员的文档，而是作为一份指南，展示 Python logging 模块的构建方式，并鼓励好奇者深入研究。

为什么要使用 logging 模块？

开发人员可能会争辩说，为什么简单的 print 语句就足够了？logging 模块提供了多项好处，包括：

• 多线程支持
• 通过不同的日志记录级别进行分类
• 灵活性和可配置性
• 将方式与内容分离

最后一点，即实际将我们记录的内容与我们记录的方式分离，实现了软件不同部分之间的协作。例如，它允许框架或库的开发人员添加日志，并让系统管理员或负责运行时配置的人员在稍后决定应该记录什么。

logging 模块中的内容

logging 模块完美地分离了其每个部分的职责（遵循 Apache Log4j API 的方法）。让我们看看日志行如何在模块的代码中传递，并探索其不同的部分。

Logger（日志器）

Logger 是开发人员通常与之交互的对象。它们是指示我们想要记录什么的主要 API。

给定一个 logger 实例，我们可以对其进行分类，并请求发出消息，而无需担心它们将如何或在哪里发出。

例如，当我们编写 logger.info("Stock was sold at %s", price) 时，我们心中有以下模型：

图片来源：

opensource.com

我们请求一行，并假设 logger 中执行了一些代码，使该行出现在控制台/文件中。但实际上内部发生了什么？

Log record（日志记录）

Log record 是 logging 模块用来传递所有必需信息的包。它们包含有关请求日志的函数、传递的字符串、参数、调用堆栈信息等信息。

这些是要记录的对象。每次我们调用 logger 时，我们都在创建这些对象的实例。但是，这些对象如何序列化为流呢？通过 Handler！

Handler（处理程序）

Handler 将日志记录发出到任何输出。它们根据其构建目的来获取和处理日志记录。

例如，FileHandler 将获取日志记录并将其附加到文件中。

标准的 logging 模块已经带有多个内置的处理程序，例如：

• 多个文件处理程序（TimeRotated、SizeRotated、Watched）可以将内容写入文件
• StreamHandler 可以将流定向到 stdout 或 stderr 等
• SMTPHandler 通过电子邮件发送日志记录
• SocketHandler 将 LogRecord 发送到流式套接字
• SyslogHandler、NTEventHandler、HTTPHandler、MemoryHandler 等

我们现在有了一个更接近现实的模型：

图片来源：

opensource.com

但是大多数处理程序都使用简单的字符串（SMTPHandler、FileHandler 等），因此您可能想知道这些结构化的 LogRecord 如何转换为易于序列化的字节...

Formatter（格式化器）

让我介绍 Formatter。Formatter 负责将富含元数据的 LogRecord 序列化为字符串。如果没有提供格式化器，则会有一个默认格式化器。

logging 库提供的通用格式化器类将模板和样式作为输入。然后，可以为 LogRecord 对象中的所有属性声明占位符。

例如：'%(asctime)s %(levelname)s %(name)s: %(message)s' 将生成如下日志：2017-07-19 15:31:13,942 INFO parent.child: Hello EuroPython。

请注意，属性 message 是将日志的原始模板与提供的参数进行插值的结果。（例如，对于 logger.info("Hello %s", "Laszlo")，消息将是 "Hello Laszlo"）。

所有默认属性都可以在 日志记录文档中找到。

好的，现在我们了解了格式化器，我们的模型又发生了变化：

图片来源：

opensource.com

Filter（过滤器）

我们日志记录工具包中的最后一个对象是过滤器。

过滤器允许更精细地控制应发出哪些日志。可以将多个过滤器附加到 logger 和 handler。为了发出日志，所有过滤器都应允许记录通过。

用户可以使用 filter 方法将自己的过滤器声明为对象，该方法将记录作为输入，并返回 True/False 作为输出。

考虑到这一点，这是当前的日志记录工作流程：

图片来源：

opensource.com

logger 层次结构

此时，您可能会对模块如此巧妙地为您隐藏的复杂性和配置量印象深刻，但还有更多需要考虑的：logger 层次结构。

我们可以通过 logging.getLogger(<logger_name>) 创建 logger。传递给 getLogger 的字符串可以通过使用点分隔元素来定义层次结构。

例如，logging.getLogger("parent.child") 将创建一个名为 "child" 的 logger，其父 logger 名为 "parent"。Logger 实例是由 logging 模块管理的全局对象，因此可以在我们项目的任何地方方便地检索它们。

Logger 实例也称为通道。层次结构允许开发人员定义通道及其层次结构。

在日志记录传递到 logger 中的所有处理程序之后，将递归调用父级的处理程序，直到我们到达顶部 logger（定义为空字符串）或 logger 配置了 propagate = False。我们可以在更新后的图表中看到它：

图片来源：

opensource.com

请注意，不会调用父 logger，只会调用其处理程序。这意味着 logger 类中的过滤器和其他代码不会在父级上执行。这是向 logger 添加过滤器时常见的陷阱。

回顾工作流程

我们已经检查了职责的分离以及如何微调日志过滤。但是还有两个我们尚未提及的其他属性：

1. Logger 可以被禁用，从而不允许从它们发出任何记录。
2. 可以在 logger 和 handler 中配置有效级别。

例如，当 logger 配置了 INFO 级别时，只会传递 INFO 级别及以上的级别。相同的规则适用于处理程序。

考虑到所有这些，日志记录文档中的最终流程图如下所示：

图片来源：

opensource.com

如何使用 logging

现在我们已经了解了 logging 模块的各个部分和设计，现在是时候检查开发人员如何与之交互了。这是一个代码示例：

import logging

def sample_function(secret_parameter):
    logger = logging.getLogger(__name__)  # __name__=projectA.moduleB
    logger.debug("Going to perform magic with '%s'",  secret_parameter)
    ...
    try:
        result = do_magic(secret_parameter)
    except IndexError:
        logger.exception("OMG it happened again, someone please tell Laszlo")
    except:
        logger.info("Unexpected exception", exc_info=True)
        raise
    else:
        logger.info("Magic with '%s' resulted in '%s'", secret_parameter, result, stack_info=True)

这使用模块 __name__ 创建一个 logger。它将根据项目结构创建通道和层次结构，因为 Python 模块用点连接。

logger 变量引用 logger "module"，将 "projectA" 作为父级，而 "projectA" 又将 "root" 作为其父级。

在第 5 行，我们看到了如何执行调用以发出日志。我们可以使用方法 debug、info、error 或 critical 来使用适当的级别进行日志记录。

在记录消息时，除了模板参数外，我们还可以传递具有特定含义的关键字参数。最有趣的是 exc_info 和 stack_info。这些将分别添加有关当前异常和堆栈帧的信息。为了方便起见，logger 对象中提供了一个方法 exception，它与调用 error 并带有 exc_info=True 相同。

这些是使用 logger 模块的基础知识。ʘ‿ʘ。但也值得提及一些通常被认为是糟糕实践的用法。

贪婪字符串格式化

应尽可能避免使用 loggger.info("string template {}".format(argument))，而应使用 logger.info("string template %s", argument)。这是一种更好的实践，因为只有在将要发出日志时才会使用实际的字符串插值。如果不这样做，可能会在我们在 INFO 以上级别进行日志记录时浪费周期，因为插值仍然会发生。

捕获和格式化异常

通常，我们希望在 catch 块中记录有关异常的信息，并且感觉很直观地使用：

try:
    ...
except Exception as error:
    logger.info("Something bad happened: %s", error)

但是，该代码可能会为我们提供类似 Something bad happened: "secret_key." 的日志行。 这不是很有用。如果我们像之前说明的那样使用 exc_info，它将产生以下结果：

try:
    ...
except Exception:
    logger.info("Something bad happened", exc_info=True)

Something bad happened
Traceback (most recent call last):
  File "sample_project.py", line 10, in code
    inner_code()
  File "sample_project.py", line 6, in inner_code
    x = data["secret_key"]
KeyError: 'secret_key'

这不仅包含异常的确切来源，还包含异常的类型。

配置我们的 logger

检测我们的软件很容易，我们需要配置日志记录堆栈并指定这些记录将如何发出。

有多种方法可以配置日志记录堆栈。

BasicConfig

这是迄今为止配置日志记录的最简单方法。只需执行 logging.basicConfig(level="INFO") 即可设置基本的 StreamHandler，它会将 INFO 级别及以上的所有内容记录到控制台。有一些参数可以自定义此基本配置。其中一些是：

格式	描述	示例
filename	指定应创建 FileHandler，使用指定的文件名，而不是 StreamHandler	/var/logs/logs.txt
format	为处理程序使用指定的格式字符串	"'%(asctime)s %(message)s'"
datefmt	使用指定的日期/时间格式	"%H:%M:%S"
level	将根 logger 级别设置为指定的级别	"INFO"

这是一种配置小型脚本的简单而实用的方法。

请注意，basicConfig 仅在运行时首次调用时有效。如果您已经配置了根 logger，则调用 basicConfig 将无效。

DictConfig

所有元素的配置以及如何连接它们可以指定为字典。此字典应具有用于 logger、handler、formatter 的不同部分以及一些基本全局参数。

这是一个示例：

config = {
    'disable_existing_loggers': False,
    'version': 1,
    'formatters': {
        'short': {
            'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'formatter': 'short',
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        '': {
            'handlers': ['console'],
            'level': 'ERROR',
        },
        'plugins': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False
        }
    },
}
import logging.config
logging.config.dictConfig(config)

调用时，dictConfig 将禁用所有现有 logger，除非 disable_existing_loggers 设置为 false。这通常是期望的行为，因为许多模块声明了一个全局 logger，该 logger 将在导入时（在调用 dictConfig 之前）实例化。

您可以在 可以用于 dictConfig 方法的模式中查看。通常，此配置存储在 YAML 文件中并从那里配置。许多开发人员通常更喜欢这种方式而不是使用 fileConfig，因为它为自定义提供了更好的支持。

扩展 logging

由于其设计方式，扩展 logging 模块很容易。让我们看一些例子：

JSON 日志记录

如果需要，我们可以通过创建自定义格式化器来记录 JSON，该格式化器将日志记录转换为 JSON 编码的字符串：

import logging
import logging.config
import json
ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName']
class JsonFormatter:
    def format(self, record):
        obj = {attr: getattr(record, attr)
                  for attr in ATTR_TO_JSON}
        return json.dumps(obj, indent=4)

handler = logging.StreamHandler()
handler.formatter = JsonFormatter()
logger = logging.getLogger(__name__)
logger.addHandler(handler)
logger.error("Hello")

添加更多上下文

在格式化器上，我们可以指定任何日志记录属性。

我们可以通过多种方式注入属性。在此示例中，我们滥用过滤器来丰富记录。

import logging
import logging.config
GLOBAL_STUFF = 1

class ContextFilter(logging.Filter):
    def filter(self, record):
        global GLOBAL_STUFF
        GLOBAL_STUFF += 1
        record.global_data = GLOBAL_STUFF
        return True

handler = logging.StreamHandler()
handler.formatter = logging.Formatter("%(global_data)s %(message)s")
handler.addFilter(ContextFilter())
logger = logging.getLogger(__name__)
logger.addHandler(handler)

logger.error("Hi1")
logger.error("Hi2")

这有效地为通过该 logger 的所有记录添加了一个属性。然后，格式化器将该属性包含在日志行中。

请注意，这会影响您的应用程序中的所有日志记录，包括您可能正在使用的库或其他框架，以及您为其发出的日志。它可以用于记录诸如所有日志行上的唯一请求 ID 之类的内容，以跟踪请求或添加额外的上下文信息。

从 Python 3.2 开始，您可以使用 setLogRecordFactory 来捕获所有日志记录创建并注入额外信息。 extra 属性和 LoggerAdapter 类也可能引起您的兴趣。

缓冲日志

有时，我们希望在发生错误时能够访问调试日志。这可以通过创建一个缓冲处理程序来实现，该处理程序将在错误发生后记录最后的调试消息。请参阅以下代码作为未经整理的示例：

import logging
import logging.handlers

class SmartBufferHandler(logging.handlers.MemoryHandler):
    def __init__(self, num_buffered, *args, **kwargs):
        kwargs["capacity"] = num_buffered + 2  # +2 one for current, one for prepop
        super().__init__(*args, **kwargs)

    def emit(self, record):
        if len(self.buffer) == self.capacity - 1:
            self.buffer.pop(0)
        super().emit(record)

handler = SmartBufferHandler(num_buffered=2, target=logging.StreamHandler(), flushLevel=logging.ERROR)
logger = logging.getLogger(__name__)
logger.setLevel("DEBUG")
logger.addHandler(handler)

logger.error("Hello1")
logger.debug("Hello2")  # This line won't be logged
logger.debug("Hello3")
logger.debug("Hello4")
logger.error("Hello5")  # As error will flush the buffered logs, the two last debugs will be logged

更多信息

对日志记录库的灵活性和可配置性的介绍旨在展示其设计如何分离关注点的优点。它还为任何有兴趣深入研究 日志记录文档和 操作指南的人提供了坚实的基础。虽然本文不是 Python 日志记录的综合指南，但以下是针对一些常见问题的解答。

我的库发出“未配置 logger”警告

请查看“Python 编程的 Hitchhiker 指南”中的 如何在库中配置日志记录。

如果 logger 没有配置级别会发生什么？

logger 的有效级别将由其父级递归定义。

我的所有日志都在本地时间。如何以 UTC 时间记录？

格式化器是答案！您需要设置格式化器的 converter 属性以生成 UTC 时间。使用 converter = time.gmtime。